/**
 * Copyright 2007-2012 Arthur Blake Licensed under the Apache License, Version 2.0 (the "License");
 * you may not use this file except in compliance with the License. You may obtain a copy of the
 * License at http://www.apache.org/licenses/LICENSE-2.0 Unless required by applicable law or
 * agreed to in writing, software distributed under the License is distributed on an "AS IS" BASIS,
 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the License for the
 * specific language governing permissions and limitations under the License.
 */
package net.sf.log4jdbc;

import java.io.IOException;
import java.io.LineNumberReader;
import java.io.StringReader;
import java.util.StringTokenizer;

import org.slf4j.LoggerFactory;
import org.slf4j.Logger;

/**
 * Delegates JDBC spy logging events to the the Simple Logging Facade for Java (slf4j).
 * @author Arthur Blake
 */
public class Slf4jSpyLogDelegator implements SpyLogDelegator {

    /**
     * Create a SpyLogDelegator specific to the Simple Logging Facade for Java (slf4j).
     */
    public Slf4jSpyLogDelegator() {}

    // logs for sql and jdbc

    /**
     * Logger that shows all JDBC calls on INFO level (exception ResultSet calls)
     */
    private static final Logger JDBCLOGGER = LoggerFactory.getLogger("jdbc.audit");

    /**
     * Logger that shows JDBC calls for ResultSet operations
     */
    private static final Logger RESULTSETLOGGER = LoggerFactory.getLogger("jdbc.resultset");

    /**
     * Logger that shows only the SQL that is occuring
     */
    private static final Logger SQLONLYLOGGER = LoggerFactory.getLogger("jdbc.sqlonly");

    /**
     * Logger that shows the SQL timing, post execution
     */
    private static final Logger SQLTIMINGLOGGER = LoggerFactory.getLogger("jdbc.sqltiming");

    /**
     * Logger that shows connection open and close events as well as current number of open connections.
     */
    private static final Logger CONNECTIONLOGGER = LoggerFactory.getLogger("jdbc.connection");

    // admin/setup logging for log4jdbc.

    /**
     * Logger just for debugging things within log4jdbc itself (admin, setup, etc.)
     */
    private static final Logger DEBUGLOGGER = LoggerFactory.getLogger("log4jdbc.debug");

    /**
     * Determine if any of the 5 log4jdbc spy loggers are turned on (jdbc.audit | jdbc.resultset | jdbc.sqlonly | jdbc.sqltiming | jdbc.connection)
     * @return true if any of the 5 spy jdbc/sql loggers are enabled at debug info or error level.
     */
    public boolean isJdbcLoggingEnabled() {
        return JDBCLOGGER.isErrorEnabled() || RESULTSETLOGGER.isErrorEnabled() || SQLONLYLOGGER.isErrorEnabled() || SQLTIMINGLOGGER.isErrorEnabled() || CONNECTIONLOGGER.isErrorEnabled();
    }

    /**
     * Called when a jdbc method throws an Exception.
     * @param spy the Spy wrapping the class that threw an Exception.
     * @param methodCall a description of the name and call parameters of the method generated the Exception.
     * @param e the Exception that was thrown.
     * @param sql optional sql that occured just before the exception occured.
     * @param execTime optional amount of time that passed before an exception was thrown when sql was being executed. caller should pass -1 if not
     *            used
     */
    public void exceptionOccured(Spy spy, String methodCall, Exception e, String sql, long execTime) {
        String classType = spy.getClassType();
        String spyNo = LogSqlSetting.LOG_PREFIX + spy.getConnectInfo();
        String header = spyNo + ". " + classType + "." + methodCall;
        if (sql == null) {
            JDBCLOGGER.error(header, e);
            SQLONLYLOGGER.error(header, e);
            SQLTIMINGLOGGER.error(header, e);
        } else {
            sql = processSql(sql);
            JDBCLOGGER.error(header + " " + sql, e);

            // if at debug level, display debug info to error log
            if (SQLONLYLOGGER.isDebugEnabled()) {
                SQLONLYLOGGER.error(spyNo + getDebugInfo() + nl + ". " + sql, e);
            } else {
                SQLONLYLOGGER.error(header + " " + sql, e);
            }

            // if at debug level, display debug info to error log
            if (SQLTIMINGLOGGER.isDebugEnabled()) {
                SQLTIMINGLOGGER.error(spyNo + getDebugInfo() + nl + ". " + sql + " {FAILED after " + execTime + " msec}", e);
            } else {
                SQLTIMINGLOGGER.error(header + " FAILED! " + sql + " {FAILED after " + execTime + " msec}", e);
            }
        }
    }

    /**
     * Called when a JDBC method from a Connection, Statement, PreparedStatement, CallableStatement or ResultSet returns.
     * @param spy the Spy wrapping the class that called the method that returned.
     * @param methodCall a description of the name and call parameters of the method that returned.
     * @param returnMsg return value converted to a String for integral types, or String representation for Object. Return types this will be null for
     *            void return types.
     */
    public void methodReturned(Spy spy, String methodCall, String returnMsg) {
        String classType = spy.getClassType();
        Logger logger = ResultSetSpy.classTypeDescription.equals(classType) ? RESULTSETLOGGER : JDBCLOGGER;
        if (logger.isInfoEnabled()) {
            String header = LogSqlSetting.LOG_PREFIX + spy.getConnectInfo() + ". " + classType + "." + methodCall + " returned " + returnMsg;
            if (logger.isDebugEnabled()) {
                logger.debug(header + " " + getDebugInfo());
            } else {
                logger.info(header);
            }
        }
    }

    /**
     * Called when a spied upon object is constructed.
     * @param spy the Spy wrapping the class that called the method that returned.
     * @param constructionInfo information about the object construction
     */
    public void constructorReturned(Spy spy, String constructionInfo) {
        // not used in this implementation -- yet
    }

    private static String nl = " ";// System.getProperty("line.separator");

    /**
     * Determine if the given sql should be logged or not based on the various DumpSqlXXXXXX flags.
     * @param sql SQL to test.
     * @return true if the SQL should be logged, false if not.
     */
    private boolean shouldSqlBeLogged(String sql) {
        if (sql == null) {
            return false;
        }
        sql = sql.trim();

        if (sql.length() < 6) {
            return false;
        }
        sql = sql.substring(0, 6).toLowerCase();
        return (DriverSpy.DumpSqlSelect && "select".equals(sql)) || (DriverSpy.DumpSqlInsert && "insert".equals(sql)) || (DriverSpy.DumpSqlUpdate && "update".equals(sql))
               || (DriverSpy.DumpSqlDelete && "delete".equals(sql)) || (DriverSpy.DumpSqlCreate && "create".equals(sql));
    }

    /**
     * Special call that is called only for JDBC method calls that contain SQL.
     * @param spy the Spy wrapping the class where the SQL occured.
     * @param methodCall a description of the name and call parameters of the method that generated the SQL.
     * @param sql sql that occured.
     */
    public void sqlOccured(Spy spy, String methodCall, String sql) {
        if (!DriverSpy.DumpSqlFilteringOn || shouldSqlBeLogged(sql)) {
            if (SQLONLYLOGGER.isDebugEnabled()) {
                SQLONLYLOGGER.debug(LogSqlSetting.LOG_PREFIX + getDebugInfo() + nl + spy.getConnectInfo() + ". " + processSql(sql));
            } else if (SQLONLYLOGGER.isInfoEnabled()) {
                SQLONLYLOGGER.info(LogSqlSetting.LOG_PREFIX + processSql(sql));
            }
        }
    }

    /**
     * Break an SQL statement up into multiple lines in an attempt to make it more readable
     * @param sql SQL to break up.
     * @return SQL broken up into multiple lines
     */
    private String processSql(String sql) {
        if (sql == null) {
            return null;
        }

        if (DriverSpy.TrimSql) {
            sql = sql.trim();
        }

        StringBuilder output = new StringBuilder();

        if (DriverSpy.DumpSqlMaxLineLength <= 0) {
            output.append(sql);
        } else {
            // insert line breaks into sql to make it more readable
            StringTokenizer st = new StringTokenizer(sql);
            String token;
            // int linelength = 0;

            while (st.hasMoreElements()) {
                token = (String) st.nextElement();

                output.append(token);
                // linelength += token.length();
                output.append(" ");
                // linelength++;
                // if (linelength > DriverSpy.DumpSqlMaxLineLength)
                // {
                // output.append("\n");
                // linelength = 0;
                // }
            }
        }

        if (DriverSpy.DumpSqlAddSemicolon) {
            output.append(";");
        }

        String stringOutput = output.toString();

        if (DriverSpy.TrimExtraBlankLinesInSql) {
            LineNumberReader lineReader = new LineNumberReader(new StringReader(stringOutput));

            output = new StringBuilder();

            int contiguousBlankLines = 0;
            try {
                while (true) {
                    String line = lineReader.readLine();
                    if (line == null) {
                        break;
                    }

                    // is this line blank?
                    if (line.trim().length() == 0) {
                        contiguousBlankLines++ ;
                        // skip contiguous blank lines
                        if (contiguousBlankLines > 1) {
                            continue;
                        }
                    } else {
                        contiguousBlankLines = 0;
                        output.append(line);
                    }
                    // output.append("\n");
                }
            } catch (IOException e) {
                // since we are reading from a buffer, this isn't likely to
                // happen,
                // but if it does we just ignore it and treat it like its the
                // end of the stream
            }
            stringOutput = output.toString();
        }

        return stringOutput;
    }

    /**
     * Special call that is called only for JDBC method calls that contain SQL.
     * @param spy the Spy wrapping the class where the SQL occurred.
     * @param execTime how long it took the SQL to run, in milliseconds.
     * @param methodCall a description of the name and call parameters of the method that generated the SQL.
     * @param sql SQL that occurred.
     */
    public void sqlTimingOccured(Spy spy, long execTime, String methodCall, String sql) {
        if (SQLTIMINGLOGGER.isErrorEnabled() && (!DriverSpy.DumpSqlFilteringOn || shouldSqlBeLogged(sql))) {
            if (DriverSpy.SqlTimingErrorThresholdEnabled && execTime >= DriverSpy.SqlTimingErrorThresholdMsec) {
                SQLTIMINGLOGGER.error(buildSqlTimingDump(spy, execTime, methodCall, sql, SQLTIMINGLOGGER.isDebugEnabled()));
            } else if (SQLTIMINGLOGGER.isWarnEnabled()) {
                if (DriverSpy.SqlTimingWarnThresholdEnabled && execTime >= DriverSpy.SqlTimingWarnThresholdMsec) {
                    SQLTIMINGLOGGER.warn(buildSqlTimingDump(spy, execTime, methodCall, sql, SQLTIMINGLOGGER.isDebugEnabled()));
                } else if (SQLTIMINGLOGGER.isDebugEnabled()) {
                    SQLTIMINGLOGGER.debug(buildSqlTimingDump(spy, execTime, methodCall, sql, true));
                } else if (SQLTIMINGLOGGER.isInfoEnabled()) {
                    SQLTIMINGLOGGER.info(buildSqlTimingDump(spy, execTime, methodCall, sql, false));
                }
            }
        }
    }

    /**
     * Helper method to quickly build a SQL timing dump output String for logging.
     * @param spy the Spy wrapping the class where the SQL occurred.
     * @param execTime how long it took the SQL to run, in milliseconds.
     * @param methodCall a description of the name and call parameters of the method that generated the SQL.
     * @param sql SQL that occurred.
     * @param debugInfo if true, include debug info at the front of the output.
     * @return a SQL timing dump String for logging.
     */
    private String buildSqlTimingDump(Spy spy, long execTime, String methodCall, String sql, boolean debugInfo) {
        StringBuffer out = new StringBuffer(LogSqlSetting.LOG_PREFIX);

        if (debugInfo) {
            // out.append(getDebugInfo());
            // out.append(nl);
            out.append(spy.getConnectInfo());
//            out.append("]{");
        }

        // NOTE: if both sql dump and sql timing dump are on, the processSql
        // algorithm will run TWICE once at the beginning and once at the end
        // this is not very efficient but usually
        // only one or the other dump should be on and not both.

        sql = processSql(sql);

        out.append("{");
        out.append(sql);
        out.append("}USE:");
        out.append(execTime);
        out.append("ms");

        return out.toString();
    }

    /**
     * Get debugging info - the module and line number that called the logger version that prints the stack trace information from the point just
     * before we got it (net.sf.log4jdbc) if the optional log4jdbc.debug.stack.prefix system property is defined then the last call point from an
     * application is shown in the debug trace output, instead of the last direct caller into log4jdbc
     * @return debugging info for whoever called into JDBC from within the application.
     */
    private static String getDebugInfo() {
        Throwable t = new Throwable();
        t.fillInStackTrace();

        StackTraceElement[] stackTrace = t.getStackTrace();

        if (stackTrace != null) {
            String className;

            StringBuffer dump = new StringBuffer();

            /**
             * The DumpFullDebugStackTrace option is useful in some situations when we want to see the full stack trace in the debug info- watch out
             * though as this will make the logs HUGE!
             */
            if (DriverSpy.DumpFullDebugStackTrace) {
                boolean first = true;
                for (int i = 0; i < stackTrace.length; i++ ) {
                    className = stackTrace[i].getClassName();
                    if (!className.startsWith("net.sf.log4jdbc")) {
                        if (first) {
                            first = false;
                        } else {
                            dump.append("  ");
                        }
                        dump.append("at ");
                        dump.append(stackTrace[i]);
                        dump.append(nl);
                    }
                }
            } else {
                dump.append(" ");
                int firstLog4jdbcCall = 0;
                int lastApplicationCall = 0;

                for (int i = 0; i < stackTrace.length; i++ ) {
                    className = stackTrace[i].getClassName();
                    if (className.startsWith("net.sf.log4jdbc")) {
                        firstLog4jdbcCall = i;
                    } else if (DriverSpy.TraceFromApplication && className.startsWith(DriverSpy.DebugStackPrefix)) {
                        lastApplicationCall = i;
                        break;
                    }
                }
                int j = lastApplicationCall;

                if (j == 0) // if app not found, then use whoever was the last
                            // guy that called a log4jdbc class.
                {
                    j = 1 + firstLog4jdbcCall;
                }

                dump.append(stackTrace[j].getClassName()).append(".").append(stackTrace[j].getMethodName()).append("(").append(stackTrace[j].getFileName()).append(":").append(
                    stackTrace[j].getLineNumber()).append(")");
            }

            return dump.toString();
        } else {
            return null;
        }
    }

    /**
     * Log a Setup and/or administrative log message for log4jdbc.
     * @param msg message to log.
     */
    public void debug(String msg) {
        DEBUGLOGGER.debug(msg);
    }

    /**
     * Called whenever a new connection spy is created.
     * @param spy ConnectionSpy that was created.
     */
    public void connectionOpened(Spy spy) {
        if (CONNECTIONLOGGER.isDebugEnabled()) {
            CONNECTIONLOGGER.info(LogSqlSetting.LOG_PREFIX + spy.getConnectInfo() + ". Connection opened " + getDebugInfo());
            CONNECTIONLOGGER.debug(LogSqlSetting.LOG_PREFIX + ConnectionSpy.getOpenConnectionsDump());
        } else {
            CONNECTIONLOGGER.info(LogSqlSetting.LOG_PREFIX + spy.getConnectInfo() + ". Connection opened");
        }
    }

    /**
     * Called whenever a connection spy is closed.
     * @param spy ConnectionSpy that was closed.
     */
    public void connectionClosed(Spy spy) {
        if (CONNECTIONLOGGER.isDebugEnabled()) {
            CONNECTIONLOGGER.info(LogSqlSetting.LOG_PREFIX + spy.getConnectInfo() + ". Connection closed " + getDebugInfo());
            CONNECTIONLOGGER.debug(LogSqlSetting.LOG_PREFIX + ConnectionSpy.getOpenConnectionsDump());
        } else {
            CONNECTIONLOGGER.info(LogSqlSetting.LOG_PREFIX + spy.getConnectInfo() + ". Connection closed");
        }
    }
}
